Issue #1 - Flow-style protocol logging #2
Merged
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
ted-ross
force-pushed
the
tross-1-flow-logging
branch
from
7762bfd
to
84f4281
Compare
ted-ross
force-pushed
the
tross-1-flow-logging
branch
from
84f4281
to
a843a8c
Compare
jiridanek
reviewed
Mar 6, 2022
ted-ross
force-pushed
the
tross-1-flow-logging
branch
2 times, most recently
from
f680ec8
to
3c5feb7
Compare
ted-ross
force-pushed
the
tross-1-flow-logging
branch
from
6189c2e
to
36e695d
Compare
kgiusti
approved these changes
Mar 17, 2022
There was a problem hiding this comment.
LGTM, but there's a use-after-free that's being hit in the system_tests_http1_over_tcp tests that appears to be related to the plog.
Sooo... conditional approval modulo a fix for this:
2022-03-16T19:54:37.6686599Z 58: E Process 3524 error: exit code 1, expected 0
2022-03-16T19:54:37.6687288Z 58: E skrouterd -c INT.A.conf -I /home/runner/work/skupper-router/skupper-router/skupper-router/python
2022-03-16T19:54:37.6688433Z 58: E /home/runner/work/skupper-router/skupper-router/skupper-router/build/tests/system_test.dir/system_tests_http1_over_tcp/Http1OverTcpOneRouterTest/setUpClass/INT.A-4.cmd
2022-03-16T19:54:37.6689004Z 58: E >>>>
2022-03-16T19:54:37.6689355Z 58: E =================================================================
2022-03-16T19:54:37.6690046Z 58: E ==3524==ERROR: AddressSanitizer: use-after-poison on address 0x613000065cd8 at pc 0x5577a020dc40 bp 0x7f3809b9d270 sp 0x7f3809b9d260
2022-03-16T19:54:37.6690564Z 58: E WRITE of size 1 at 0x613000065cd8 thread T1
2022-03-16T19:54:37.6690999Z 58: E #0 0x5577a020dc3f in _plog_end_record_TH ../src/protocol_log.c:309
2022-03-16T19:54:37.6692762Z 58: E #1 0x5577a0217877 in _plog_thread ../src/protocol_log.c:960
2022-03-16T19:54:37.6693365Z 58: E #2 0x5577a02001b6 in _thread_init ../src/posix/threading.c:172
2022-03-16T19:54:37.6694091Z 58: E #3 0x7f380fe16608 in start_thread /build/glibc-sMfBJT/glibc-2.31/nptl/pthread_create.c:477
2022-03-16T19:54:37.6694742Z 58: E #4 0x7f380f00a162 in __clone (/lib/x86_64-linux-gnu/libc.so.6+0x11f162)
2022-03-16T19:54:37.6697114Z 58: E
2022-03-16T19:54:37.6697805Z 58: E 0x613000065cd8 is located 280 bytes inside of 320-byte region [0x613000065bc0,0x613000065d00)
2022-03-16T19:54:37.6698143Z 58: E allocated by thread T4 here:
2022-03-16T19:54:37.6698656Z 58: E #0 0x7f3810486aa5 in posix_memalign (/lib/x86_64-linux-gnu/libasan.so.5+0x10eaa5)
2022-03-16T19:54:37.6699032Z 58: E #1 0x5577a014fc28 in qd_alloc ../src/alloc_pool.c:396
2022-03-16T19:54:37.6699396Z 58: E #2 0x5577a020a786 in new_plog_record_t ../src/protocol_log.c:75
2022-03-16T19:54:37.6699775Z 58: E #3 0x5577a0217c77 in plog_start_record ../src/protocol_log.c:1069
2022-03-16T19:54:37.6700389Z 58: E #4 0x5577a0134072 in qdr_tcp_connection_ingress ../src/adaptors/tcp_adaptor.c:964
2022-03-16T19:54:37.6700832Z 58: E #5 0x5577a0138ecd in handle_listener_event ../src/adaptors/tcp_adaptor.c:1222
2022-03-16T19:54:37.6701319Z 58: E #6 0x5577a0349e9c in handle_event_with_context ../src/server.c:780
2022-03-16T19:54:37.6701669Z 58: E #7 0x5577a0349f23 in do_handle_listener ../src/server.c:791
2022-03-16T19:54:37.6702012Z 58: E #8 0x5577a034cb12 in handle ../src/server.c:986
2022-03-16T19:54:37.6702330Z 58: E #9 0x5577a034e794 in thread_run ../src/server.c:1095
2022-03-16T19:54:37.6702684Z 58: E #10 0x5577a02001b6 in _thread_init ../src/posix/threading.c:172
2022-03-16T19:54:37.6703272Z 58: E #11 0x7f380fe16608 in start_thread /build/glibc-sMfBJT/glibc-2.31/nptl/pthread_create.c:477
2022-03-16T19:54:37.6703586Z 58: E
2022-03-16T19:54:37.6703852Z 58: E Thread T1 created by T0 here:
2022-03-16T19:54:37.6704341Z 58: E #0 0x7f38103b2805 in pthread_create (/lib/x86_64-linux-gnu/libasan.so.5+0x3a805)
2022-03-16T19:54:37.6704740Z 58: E #1 0x5577a0200325 in sys_thread ../src/posix/threading.c:181
2022-03-16T19:54:37.6705102Z 58: E #2 0x5577a0219884 in _plog_init ../src/protocol_log.c:1268
2022-03-16T19:54:37.6705474Z 58: E #3 0x5577a02c973c in qdr_adaptors_init ../src/router_core/router_core_thread.c:165
2022-03-16T19:54:37.6705883Z 58: E #4 0x5577a02aa554 in qdr_core_setup_init ../src/router_core/router_core.c:67
2022-03-16T19:54:37.6706254Z 58: E #5 0x5577a02ab3ac in qdr_core ../src/router_core/router_core.c:117
2022-03-16T19:54:37.6706988Z 58: E #6 0x5577a0338849 in qd_router_setup_late ../src/router_node.c:2083
2022-03-16T19:54:37.6707589Z 58: E #7 0x7f380ad08ff4 (/lib/x86_64-linux-gnu/libffi.so.7+0x6ff4)
2022-03-16T19:54:37.6707972Z 58: E #8 0x7ffe0fbe442f ([stack]+0x1f42f)
2022-03-16T19:54:37.6708196Z 58: E
2022-03-16T19:54:37.6708416Z 58: E Thread T4 created by T0 here:
2022-03-16T19:54:37.6708861Z 58: E #0 0x7f38103b2805 in pthread_create (/lib/x86_64-linux-gnu/libasan.so.5+0x3a805)
2022-03-16T19:54:37.6709208Z 58: E #1 0x5577a0200325 in sys_thread ../src/posix/threading.c:181
2022-03-16T19:54:37.6709738Z 58: E #2 0x5577a03561dc in qd_server_run ../src/server.c:1489
2022-03-16T19:54:37.6710234Z 58: E #3 0x5577a03b1938 in main_process ../router/src/main.c:105
2022-03-16T19:54:37.6710538Z 58: E #4 0x5577a03b393c in main ../router/src/main.c:359
2022-03-16T19:54:37.6711019Z 58: E #5 0x7f380ef0f0b2 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x240b2)
2022-03-16T19:54:37.6711305Z 58: E
2022-03-16T19:54:37.6711753Z 58: E SUMMARY: AddressSanitizer: use-after-poison ../src/protocol_log.c:309 in _plog_end_record_TH
2022-03-16T19:54:37.6712139Z 58: E Shadow bytes around the buggy address:
2022-03-16T19:54:37.6712423Z 58: E 0x0c2680004b40: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
2022-03-16T19:54:37.6714375Z 58: E 0x0c2680004b50: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
2022-03-16T19:54:37.6714699Z 58: E 0x0c2680004b60: 00 00 00 00 00 00 00 00 fa fa fa fa fa fa fa fa
2022-03-16T19:54:37.6715003Z 58: E 0x0c2680004b70: fa fa fa fa fa fa fa fa 00 00 00 00 00 00 00 00
2022-03-16T19:54:37.6715318Z 58: E 0x0c2680004b80: 00 00 00 00 00 00 00 00 00 00 f7 f7 f7 f7 f7 f7
2022-03-16T19:54:37.6715626Z 58: E =>0x0c2680004b90: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7[f7]00 00 00 00
2022-03-16T19:54:37.6715936Z 58: E 0x0c2680004ba0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
2022-03-16T19:54:37.6716251Z 58: E 0x0c2680004bb0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
2022-03-16T19:54:37.6716542Z 58: E 0x0c2680004bc0: 00 00 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
2022-03-16T19:54:37.6717035Z 58: E 0x0c2680004bd0: f7 f7 f7 f7 00 00 00 00 fa fa fa fa fa fa fa fa
2022-03-16T19:54:37.6717372Z 58: E 0x0c2680004be0: fa fa fa fa fa fa fa fa 00 00 00 00 00 00 00 00
2022-03-16T19:54:37.6717876Z 58: E Shadow byte legend (one shadow byte represents 8 application bytes):
2022-03-16T19:54:37.6718211Z 58: E Addressable: 00
2022-03-16T19:54:37.6718646Z 58: E Partially addressable: 01 02 03 04 05 06 07
2022-03-16T19:54:37.6718938Z 58: E Heap left redzone: fa
2022-03-16T19:54:37.6719211Z 58: E Freed heap region: fd
2022-03-16T19:54:37.6719463Z 58: E Stack left redzone: f1
2022-03-16T19:54:37.6719886Z 58: E Stack mid redzone: f2
2022-03-16T19:54:37.6720132Z 58: E Stack right redzone: f3
2022-03-16T19:54:37.6720393Z 58: E Stack after return: f5
2022-03-16T19:54:37.6720642Z 58: E Stack use after scope: f8
2022-03-16T19:54:37.6721058Z 58: E Global redzone: f9
2022-03-16T19:54:37.6721307Z 58: E Global init order: f6
2022-03-16T19:54:37.6721541Z 58: E Poisoned by user: f7
2022-03-16T19:54:37.6721791Z 58: E Container overflow: fc
2022-03-16T19:54:37.6722261Z 58: E Array cookie: ac
2022-03-16T19:54:37.6722511Z 58: E Intra object redzone: bb
2022-03-16T19:54:37.6722766Z 58: E ASan internal: fe
2022-03-16T19:54:37.6723001Z 58: E Left alloca redzone: ca
2022-03-16T19:54:37.6723261Z 58: E Right alloca redzone: cb
2022-03-16T19:54:37.6723497Z 58: E Shadow gap: cc
2022-03-16T19:54:37.6723726Z 58: E ==3524==ABORTING
2022-03-16T19:54:37.6723923Z 58: E <<<<
2022-03-16T19:54:37.6724118Z 58:
2022-03-16T19:54:37.6724629Z 58: /home/runner/work/skupper-router/skupper-router/skupper-router/tests/system_test.py:874: RuntimeError
2022-03-16T19:54:37.6806576Z 58: ---------------------------- Captured log teardown -----------------------------
2022-03-16T19:54:37.6807231Z 58: DEBUG root:system_test.py:1462 2022-03-16 19:53:21.974807 TestServer: TestServer :20513 shutting down
2022-03-16T19:54:37.6807788Z 58: DEBUG root:system_test.py:1462 2022-03-16 19:53:22.026142 TestServer: TestServer :20513 closed
2022-03-16T19:54:37.6808357Z 58: DEBUG root:system_test.py:1462 2022-03-16 19:53:22.039364 TestServer: TestServer :20512 shutting down
2022-03-16T19:54:37.6809228Z 58: DEBUG root:system_test.py:1462 2022-03-16 19:53:22.081694 TestServer: TestServer :20512 closed
2022-03-16T19:54:37.6810105Z 58: - generated xml file: /home/runner/work/skupper-router/skupper-router/skupper-router/build/tests/junitxmls/system_tests_http1_over_tcp.xml -
2022-03-16T19:54:37.6810572Z 58: =========================== short test summary info ============================
2022-03-16T19:54:37.6811116Z 58: ERROR ::Http1OverTcpOneRouterTest::test_008_put_10 - RuntimeError: Errors dur...
2022-03-16T19:54:37.6811811Z 58: ==================== 12 passed, 1 error in 86.55s (0:01:26) ====================
…ture and TCP-adaptor integration.
…ous improvements.
ted-ross
force-pushed
the
tross-1-flow-logging
branch
from
36e695d
to
4351e1a
Compare
This was referenced Mar 29, 2022
jiridanek
added a commit
that referenced
this pull request
Apr 7, 2022
…nnection_CT` (#213) ``` WARNING: ThreadSanitizer: data race (pid=3244) Write of size 1 at 0x7b54000c9942 by thread T1: #0 qdr_close_connection_CT src/router_core/connections.c:267 (skrouterd+0x4875d8) #1 qdr_core_close_connection_CT src/router_core/connections.c:283 (skrouterd+0x487766) #2 router_core_thread src/router_core/router_core_thread.c:236 (skrouterd+0x4a382a) #3 _thread_init src/posix/threading.c:172 (skrouterd+0x47ad5d) Previous read of size 1 at 0x7b54000c9942 by main thread: #0 qdr_connection_process src/router_core/connections.c:308 (skrouterd+0x48783c) #1 _do_reconnect src/adaptors/http1/http1_server.c:432 (skrouterd+0x43bfcc) #2 qd_timer_visit src/timer.c:320 (skrouterd+0x4c587f) #3 handle src/server.c:980 (skrouterd+0x4c114e) #4 thread_run src/server.c:1095 (skrouterd+0x4c2f57) #5 qd_server_run src/server.c:1491 (skrouterd+0x4c3acc) #6 main_process router/src/main.c:105 (skrouterd+0x424e5c) #7 main router/src/main.c:359 (skrouterd+0x4242ec) Location is heap block of size 640 at 0x7b54000c9900 allocated by thread T4: #0 posix_memalign <null> (libtsan.so.0+0x32a23) #1 qd_alloc src/alloc_pool.c:396 (skrouterd+0x448d09) #2 new_qdr_connection_t src/router_core/connections.c:44 (skrouterd+0x486d21) #3 qdr_connection_opened src/router_core/connections.c:88 (skrouterd+0x486d21) #4 _setup_client_connection src/adaptors/http1/http1_client.c:316 (skrouterd+0x4342da) #5 _handle_connection_events src/adaptors/http1/http1_client.c:452 (skrouterd+0x4342da) #6 handle_event_with_context src/server.c:780 (skrouterd+0x4c11f9) #7 do_handle_raw_connection_event src/server.c:786 (skrouterd+0x4c11f9) #8 handle src/server.c:1063 (skrouterd+0x4c11f9) #9 thread_run src/server.c:1095 (skrouterd+0x4c2f57) #10 _thread_init src/posix/threading.c:172 (skrouterd+0x47ad5d) ```
This was referenced May 23, 2022
This was referenced Sep 11, 2023
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
No description provided.